主题
Go trace：把“请求在等什么”放回时间线上
CPU profile 能告诉你哪些函数消耗了计算资源，却不能独自解释一个只算了很短时间、响应却慢了几十毫秒的请求。Go execution trace 记录运行时事件：goroutine 何时创建、阻塞、被唤醒、真正开始运行，以及 GC、系统调用、处理器状态怎样变化。把这些事件按时间排列，才能区分“还没等到结果”和“结果到了，但还没轮到它运行”。[1]
本文在 Go 1.27.2、Linux/amd64 上生成并解析一份真实的短 trace。例子只在本地睡眠 20 ms、做少量计算、执行一次受控 GC。它用来学习证据的读法，不代表生产系统的延迟构成。
三种“慢”，需要看三段不同的时间
| 状态或现象 | 含义 | 下一步看什么 |
|---|---|---|
| Running | goroutine 正在某个线程上执行 Go 代码 | CPU profile、热函数、是否存在 GC assist |
| Waiting / 阻塞 | 等 channel、锁、定时器、网络等条件 | 阻塞原因、哪条路径负责让条件成立 |
| Runnable | 已经可运行，尚未真正拿到执行机会 | 调度延迟、运行队列、CPU 配额、其他计算负载 |
| GC 的 STW 区间 | 运行时暂停应用 goroutine 的特定阶段 | 与目标请求的等待区间是否重叠，实际暂停多长 |
G 是 goroutine，M 是 OS 线程，P 是执行 Go 代码所需的运行时处理器资源。P 的数量受 GOMAXPROCS 控制；它与机器 CPU 数量、容器 CPU 配额并非总是同一个数字。trace 能观察进程内的调度状态，容器是否被限额、宿主机是否抢占，还需对应系统指标。不能看到 Runnable 就断言“Go 调度器有 bug”。[1][2]
正在绘制图示…
查看图源代码
stateDiagram-v2
[*] --> Runnable: 创建或被唤醒
Runnable --> Running: 获得执行机会
Running --> Waiting: 接收 channel / 等锁 / 等 I/O
Waiting --> Runnable: 条件满足
Running --> Runnable: 抢占或主动让出
Running --> Done: 函数返回
Done --> [*]
Waiting 到 Runnable 是“可以做了”，Runnable 到 Running 才是“真的开始做”。把这两段混在一起，会把慢下游误判成 CPU 不够，也会把 CPU 排队误判成下游慢。
给一次本地任务加上可读的名字
最小入口是 trace.Start(w) 与 trace.Stop()，后者负责等待写出剩余 trace 数据。一个普通 trace 尚未结束时再次 Start 会返回错误。测试、HTTP 服务也有对应入口：go test -trace=trace.out，以及受保护的 /debug/pprof/trace?seconds=5。[1][3]
仅有运行时栈时，“这几条 goroutine 是同一个请求吗”未必容易回答。三个用户标记各有用途：
| API | 应该标什么 | 生命周期约束 |
|---|---|---|
NewTask(ctx, "one-job") / task.End() | 一次逻辑操作，可跨 goroutine | 把返回的 ctx 传给相关工作，明确结束 |
WithRegion(ctx, "compute", fn) | 同一个 goroutine 内的一段工作 | 开始、结束在同一 goroutine；可以嵌套 |
Log(ctx, "phase", "input-ready") | 一个离散事件 | 文本会写入 trace，避免密钥与客户数据 |
下面是完整程序中的关键部分：
go
ctx, task := trace.NewTask(ctx, "one-job")
defer task.End()
result := make(chan int)
go func() {
trace.WithRegion(ctx, "wait-input", func() {
time.Sleep(20 * time.Millisecond)
})
trace.Log(ctx, "phase", "input-ready")
total := 0
trace.WithRegion(ctx, "compute", func() {
for i := 0; i < 100000; i++ { total += i % 7 }
})
result <- total
}()
var n int
trace.WithRegion(ctx, "wait-result", func() { n = <-result })真实输出：
text
result: 299995
trace enabled: truetrue 是输出那一刻的状态；run 返回前 defer 已经停止 trace，测试会再断言 IsEnabled() 为 false。另一个负向测试在同一 trace 活跃期间再次调用 Start，实际得到 execution tracer already enabled。这些是生命周期断言，不靠文件“看起来不为空”来猜采集是否正确。[1]
从原始事件拆出两段等待
当前 Go 1.27.2 工具的调试输出模式是 wire、parsed、footprint。旧文章里的 -d=1 不应不查版本就照抄。本文执行：
bash
go tool trace -d=parsed out/trace.out > out/events.txt本次 main goroutine 的一组真实事件如下，保留了原始单调时间戳：
text
Time=25438583648576 GoID=1 Running->Waiting Reason="chan receive"
Time=25438603962752 GoID=1 Waiting->Runnable Reason=""
Time=25438603974528 GoID=1 Runnable->Running Reason=""这些行摘自完整事件输出，省略了 M、P 与打印前缀。第一段相差 20.314176 ms，表示等待 channel 条件；第二段相差 11.776 μs，是可运行之后的调度等待。程序另有 input-ready 日志，随后 worker 发出结果，与这个解阻塞过程对应。时间戳与 goroutine ID 只是本次记录的值，不应写进通用解析器当常量。[1][4]
正在绘制图示…
查看图源代码
sequenceDiagram
participant Main as 主 goroutine
participant Worker as 工作 goroutine
participant Scheduler as 运行时
Main->>Worker: 创建工作，传播 task context
Main->>Main: 接收结果，进入 Waiting
Worker->>Worker: sleep 20 ms，再计算
Worker->>Main: channel 发送结果
Scheduler->>Main: Waiting → Runnable
Note over Main,Scheduler: 本次等待 11.776 μs 后得到执行机会
Scheduler->>Main: Runnable → Running
Main->>Main: 取得结果，结束 wait-result region
这段因果解释有程序结构和唤醒事件共同支持。反过来，两个事件碰巧发生在同一时间附近，不足以证明一个导致另一个。跨进程 RPC 的服务端执行、网络中的排队并不会自动进入当前进程的 runtime trace；要结合分布式追踪、网络与对端证据。
用汇总找入口，用时间线判断先后
go tool trace 可以导出四种 pprof 风格的汇总：[4]
| 参数 | 看什么 | 不能替代什么 |
|---|---|---|
-pprof=sched | 从可运行到实际执行的调度延迟 | 不能独自证明容器被限额 |
-pprof=sync | 同步等待，如 channel、锁 | 不涵盖所有墙钟等待，也不是 CPU 用量 |
-pprof=net | 网络阻塞相关的等待 | 不等于远端数据库查询计划 |
-pprof=syscall | 系统调用阻塞 | 不等于完整内核调用栈分析 |
bash
go tool trace -pprof=sync out/trace.out > out/sync.pb.gz
go tool pprof -top out/sync.pb.gz本次实际输出摘录：
text
Type: delay
Showing nodes accounting for 20.32ms, 100% of 20.32ms total
20.32ms 100% runtime.chanrecv1这与主 goroutine 等结果约 20 ms 对得上。sched 汇总则是所有相关事件的聚合，包含运行时自身活动，不能直接把它的总数当成这一个任务的延迟。这个实验不包含网络访问，net 视图没有业务网络阻塞样本，这不是采集失败。
需要交互查看时，可在自己的分析机运行：
bash
go tool trace -http=127.0.0.1:8081 out/trace.out从 goroutine analysis、任务与 region 列表定位目标，再进入 timeline 对照 P 的执行条带、阻塞与唤醒、GC 区间。官方工具说明 trace viewer 主要在 Chrome/Chromium 上测试。本文实际验证的是离线文本解析和四类导出，没有浏览器渲染或截图验证。[4]
GC 长，不等于整个 GC 都在暂停服务
例子取得结果后显式调用 runtime.GC()，目的是让一次 GC 在很短的 trace 中可见。事件里确实出现两个 STW 阶段：
text
stop-the-world (GC sweep termination)
stop-the-world (GC mark termination)本次 sweep termination 的区间约 10.752 μs，mark termination 约 108.096 μs，由对应 RangeBegin/RangeEnd 时间戳相减得到。并发标记阶段在它们之间，不能把整个 GC 周期长度都当成应用暂停。GC 还可能通过后台标记占用 CPU，或让分配中的 goroutine 执行 mark assist；这些影响也不是同一个“STW 总时长”。[2]
排查尾延迟时，把目标请求的时间窗与 GC 区间对齐：若请求大部分时间在等 channel，而且那一段没有覆盖长 STW，就没有依据把几十毫秒都归给 GC。若请求被唤醒后长期 Runnable，需要再检查可用 P、CPU 饱和或限额，而不是从 GC 恰好出现就直接下结论。
采集窗口、数据量和隐私一起控制
trace 的事件量会随 goroutine 切换、分配和运行时活动增长，采集开销不是一个适用于所有服务的固定百分比。先在可控环境量采集前后的 CPU、延迟和输出字节，再批准有限窗口。不要为找偶发问题无限制写 trace；全量内存与阻塞采样也会扰动调度，适合分开测的工具就不要一起全开。[5]
Go 1.27.2 还有 trace.FlightRecorder：它维护一个近期事件窗口，适合事件发生后再取快照。FlightRecorderConfig.MinAge 描述希望保留的时间范围，MaxBytes 优先，但文档明确它只是提示，不能保证实际内存或 WriteTo 输出绝不超过该值；同一 recorder 的 WriteTo 也不能并发执行。本篇只核对了 API 与文档，没有把 flight recorder 声称为已验证部署方案。[1]
保存 trace 时一起保存工具链版本、构建 ID、采集时间窗、负载条件、采集参数和触发原因。尽量用同版本工具解析，升级前用真实文件验证兼容性。文件里有函数路径、任务名、日志内容，交给外部分析前要按诊断数据而非普通日志处理。
验证范围
完整程序与生命周期测试通过 go test、go test -race 和 go vet。四种 trace 汇总成功导出并被 pprof 解析。确定性断言验证结果为 299995、trace 正确停止、重复 Start 被拒绝；时间与样本只报告本次观测，不把共享云机器的调度等待外推为 Go 的性能上限。
依据
- Go 1.27.2 runtime/trace：事件、task/region/log、Start/Stop、FlightRecorder；同时核对本机同版本
go doc。 - Go GC guide；Go 1.27.2 runtime：GC 阶段、assist、GOMAXPROCS。
- Go 1.27.2 net/http/pprof：trace HTTP 接口。
- Go 1.27.2 cmd/trace 源码：本次 CLI 同时由
go tool trace -help核对；调度、阻塞汇总实现见其中pprof.go。 - Go diagnostics：工具相互干扰与生产采集成本；execution traces 的官方改进说明。
完整复现代码
以下文件放在同一新目录，使用 Go 1.27.2，运行 bash run.sh out。out/events.txt 保存完整事件，便于逐条复核；本机的时间戳和耗时无需与文章相同。
go.mod
go.mod
module example.com/tracelab
go 1.27.2main.go
代码块 · 63 行 · 点击收起 / 展开
go
package main
import (
"context"
"fmt"
"os"
"runtime"
"runtime/trace"
"time"
)
func work(ctx context.Context) int {
ctx, task := trace.NewTask(ctx, "one-job")
defer task.End()
result := make(chan int)
go func() {
trace.WithRegion(ctx, "wait-input", func() { time.Sleep(20 * time.Millisecond) })
trace.Log(ctx, "phase", "input-ready")
total := 0
trace.WithRegion(ctx, "compute", func() {
for i := 0; i < 100000; i++ {
total += i % 7
}
})
result <- total
}()
var n int
trace.WithRegion(ctx, "wait-result", func() { n = <-result })
trace.WithRegion(ctx, "forced-gc", func() { runtime.GC() })
return n
}
func run(path string) (err error) {
f, err := os.Create(path)
if err != nil {
return err
}
defer func() {
if e := f.Close(); err == nil {
err = e
}
}()
if err = trace.Start(f); err != nil {
return err
}
defer trace.Stop()
n := work(context.Background())
if n != 299995 {
return fmt.Errorf("bad result %d", n)
}
fmt.Println("result:", n)
fmt.Println("trace enabled:", trace.IsEnabled())
return nil
}
func main() {
path := "trace.out"
if len(os.Args) > 1 {
path = os.Args[1]
}
if err := run(path); err != nil {
fmt.Fprintln(os.Stderr, err)
os.Exit(1)
}
}main_test.go
代码块 · 43 行 · 点击收起 / 展开
go
package main
import (
"context"
"os"
"path/filepath"
"runtime/trace"
"testing"
)
func TestTrace(t *testing.T) {
if n := work(context.Background()); n != 299995 {
t.Fatal(n)
}
p := filepath.Join(t.TempDir(), "trace.out")
if err := run(p); err != nil {
t.Fatal(err)
}
if trace.IsEnabled() {
t.Fatal("trace still active")
}
s, err := os.Stat(p)
if err != nil || s.Size() == 0 {
t.Fatalf("empty trace: %v", err)
}
}
func TestSecondStartRejected(t *testing.T) {
f, err := os.Create(filepath.Join(t.TempDir(), "double.out"))
if err != nil {
t.Fatal(err)
}
defer f.Close()
if err := trace.Start(f); err != nil {
t.Fatal(err)
}
defer trace.Stop()
if err := trace.Start(f); err == nil {
t.Fatal("second Start must fail")
} else {
t.Log(err)
}
}run.sh
bash
#!/usr/bin/env bash
set -euo pipefail
export TZ=UTC
out=${1:-out}
mkdir -p "$out"
go version > "$out/environment.txt"
go test -v . > "$out/test.txt"
go test -race . >> "$out/test.txt"
go vet . >> "$out/test.txt"
go build -o "$out/lab" .
GOMAXPROCS=2 "$out/lab" "$out/trace.out" > "$out/run.txt"
go tool trace -d=parsed "$out/trace.out" > "$out/events.txt"
for kind in sched sync net syscall; do
go tool trace -pprof="$kind" "$out/trace.out" > "$out/$kind.pb.gz"
go tool pprof -top "$out/$kind.pb.gz" > "$out/$kind-top.txt"
done